Skip to content

virtio/net/unixgram: Retry on ENOBUFS#556

Open
nirs wants to merge 6 commits intocontainers:mainfrom
nirs:retry-on-enobufs
Open

virtio/net/unixgram: Retry on ENOBUFS#556
nirs wants to merge 6 commits intocontainers:mainfrom
nirs:retry-on-enobufs

Conversation

@nirs
Copy link
Contributor

@nirs nirs commented Feb 19, 2026

When running iperf3 with gvproxy or vmnet-helper, krunkit breaks randomly with:

[2026-02-19T02:53:41Z ERROR devices::virtio::net::worker] Failed to process rx:
Backend(Internal(ENOBUFS)) (triggered by backend socket readable)

macOS returns ENOBUFS when the kernel socket buffer is full, rather than blocking or returning EAGAIN on non-blocking sockets. Stress testing showed that edge-triggered EVFILT_WRITE does not re-fire reliably after ENOBUFS, causing a permanent stall where the worker is blocked in kevent(), the network proxy is blocked on read(), and the guest is waiting for an interrupt.

The fix uses a one-shot kqueue timer (50μs) to retry TX after NothingWritten, ensuring progress without busy-looping. The retry delay is backend-specific: only unixgram on macOS enables it, since datagram sockets can report writable with insufficient space for a complete frame.

Changes

  1. Stop tx loop on NothingWritten — When a backend cannot write, propagate the error to process_tx_loop() and return to the event loop instead of busy-looping.

  2. Add one-shot timer to macOS epoll shim — Add add_oneshot_timer() using EVFILT_TIMER with microsecond precision. Timer events are reported with empty event bits; the caller identifies them by udata.

  3. Add timer-based TX retry in worker — When process_tx() fails with NothingWritten, set tx_has_deferred_frame and schedule a retry via the one-shot timer. The retry delay is provided by the backend via write_retry_delay_us() (default 0, no timer).

  4. Retry ENOBUFS after delay — Map ENOBUFS to WriteError::NothingWritten and override write_retry_delay_us() to return 50μs in the unixgram backend on macOS.

  5. Track ENOBUFS retries — Add a retry counter to log the first ENOBUFS event and recovery. 94% of events resolve on the first retry (50μs), worst case 5 retries (~2ms).

  6. Unify read/write logs — Unify read_frame and write_frame debug logs.

Test results

Tested 600 seconds bidirectional iperf3 runs with 8 streams:

iperf3 -c addr --bidir -P 8 --json -t 600
stress-sum

Configuration:

Fixes #555

@gemini-code-assist
Copy link

Summary of Changes

Hello @nirs, I'm Gemini Code Assist1! I'm currently reviewing this pull request and will post my feedback shortly. In the meantime, here's a summary to help you and other reviewers quickly get up to speed!

This pull request addresses a critical network stability and performance issue on macOS when using gvproxy with iperf3. It introduces specific error handling for ENOBUFS (no buffer space available) errors, which macOS returns when the kernel socket buffer is full. By treating this condition as a signal to retry the write operation, the PR prevents crashes and enables successful, stable network stress testing, significantly improving the robustness of the virtio network backend on macOS.

Highlights

  • macOS ENOBUFS Handling: Modified the write_frame function in virtio/net/unixgram to explicitly handle nix::Error::ENOBUFS on macOS. This error, which occurs when the kernel socket buffer is full, is now mapped to WriteError::NothingWritten, allowing the caller to retry the send operation instead of treating it as a fatal error.
  • Improved Network Stability: This change prevents gvproxy from crashing during iperf3 stress tests on macOS, which previously occurred due to unhandled ENOBUFS errors. The system can now gracefully handle transient buffer full conditions.

🧠 New Feature in Public Preview: You can now enable Memory to help Gemini Code Assist learn from your team's feedback. This makes future code reviews more consistent and personalized to your project's style. Click here to enable Memory in your admin console.

Changelog
  • src/devices/src/virtio/net/unixgram.rs
    • Modified the write_frame function to use a match statement for the send system call result.
    • Added a specific case to catch nix::Error::ENOBUFS and return WriteError::NothingWritten.
    • Included comments explaining the macOS-specific behavior of ENOBUFS and referencing a similar handling in vmnet-helper.
Activity
  • The author identified a critical issue where iperf3 stress tests would fail within seconds on macOS due to Backend(Internal(ENOBUFS)) errors when using gvproxy.
  • Detailed test results were provided, demonstrating that the change enables successful iperf3 bidirectional stress testing for 600 seconds, with consistent performance using vmnet-helper and improved stability for gvproxy.
  • The author noted that without this change, performance testing was impossible as the stress test would immediately break.
Using Gemini Code Assist

The full guide for Gemini Code Assist can be found on our documentation page, here are some quick tips.

Invoking Gemini

You can request assistance from Gemini at any point by creating a comment using either /gemini <command> or @gemini-code-assist <command>. Below is a summary of the supported commands on the current page.

Feature Command Description
Code Review /gemini review Performs a code review for the current pull request in its current state.
Pull Request Summary /gemini summary Provides a summary of the current pull request in its current state.
Comment @gemini-code-assist Responds in comments when explicitly tagged, both in pull request comments and review comments.
Help /gemini help Displays a list of available commands.

Customization

To customize Gemini Code Assist for GitHub experience, repository maintainers can create a configuration file and/or provide a custom code review style guide (such as PEP-8 for Python) by creating and adding files to a .gemini/ folder in the base of the repository. Detailed instructions can be found here.

Limitations & Feedback

Gemini Code Assist may make mistakes. Please leave feedback on any instances where its feedback is incorrect or counter productive. You can react with 👍 and 👎 on @gemini-code-assist comments. If you're interested in giving your feedback about your experience with Gemini Code Assist for Github and other Google products, sign up here.

You can also get AI-powered code generation, chat, as well as code reviews directly in the IDE at no cost with the Gemini Code Assist IDE Extension.

Footnotes

  1. Review the Privacy Notices, Generative AI Prohibited Use Policy, Terms of Service, and learn how to configure Gemini Code Assist in GitHub here. Gemini can make mistakes, so double check it and use code with caution.

Copy link

@gemini-code-assist gemini-code-assist bot left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Code Review

This pull request correctly handles the ENOBUFS error on macOS for unixgram sockets by mapping it to WriteError::NothingWritten, which allows the caller to retry sending the frame. This prevents a fatal error when the kernel socket buffer is full. I've added one suggestion to also handle EAGAIN and EWOULDBLOCK in the same way to improve portability and make the error handling more robust across different Unix-like systems.

@slp
Copy link
Collaborator

slp commented Feb 23, 2026

@mtjhrc PTAL

@mtjhrc
Copy link
Collaborator

mtjhrc commented Feb 24, 2026

The change LGTM, but what did you mean by this in the commit message:

macOS returns ENOBUFS when the kernel socket buffer is full, rather
than blocking or returning EAGAIN. The kernel does not provide any
readiness notification for this condition, so the only recovery is
to retry the send
.

Wouldn't we get notified via kqueue the socket is writable again? (same as EAGAIN on Linux...)

@nirs
Copy link
Contributor Author

nirs commented Feb 24, 2026

The change LGTM, but what did you mean by this in the commit message:

macOS returns ENOBUFS when the kernel socket buffer is full, rather
than blocking or returning EAGAIN. The kernel does not provide any
readiness notification for this condition, so the only recovery is
to retry the send
.

Wouldn't we get notified via kqueue the socket is writable again? (same as EAGAIN on Linux...)

I could not find any evidence that we can use non-blocking io to detect if the socket is writable or not. The only info I could find was in FreeBSD mailing list thread explaining that the only way to recover is retrying.

Looking at early experiments with vmnet-helper I did not try non-blocking io, or maybe I did not commit this since it did not work.

@mtjhrc
Copy link
Collaborator

mtjhrc commented Feb 24, 2026

Hmm, but we are already using a non-blocking socket here. Notably we also use EVFILT_WRITE | EV_CLEAR, which should be similar to the edge triggered epoll behavior on Linux.

What I am wondering is that, If receiving an ENOBUFS meant we won't get woken up by EVFILT_WRITE, this could still stall temporarily - suppose there is a burst of network packets, causing ENOBUFS, followed by period of no packets from the guest, that could mean we wouldn't get kicked from guest or from the socket until guest tries to send more packets. (on Linux we would get notified the socket became writable again and we would continue processing the queue).

@nirs
Copy link
Contributor Author

nirs commented Feb 24, 2026

What I am wondering is that, If receiving an ENOBUFS meant we won't get woken up by EVFILT_WRITE, this could still stall temporarily - suppose there is a burst of network packets, causing ENOBUFS, followed by period of no packets from the guest, that could mean we wouldn't get kicked from guest or from the socket until guest tries to send more packets. (on Linux we would get notified the socket became writable again and we would continue processing the queue).

I'm not sure that edge triggered behavior works for datagram socket. The socket is probably always writable since we never get EAGAIN. But this is a separate issue to investigate, retrying ENOBUFS works.

It can be interesting to count retries and be able to get stats so we have some visibility on this issue. Maybe add debug log in this case?

@mtjhrc
Copy link
Collaborator

mtjhrc commented Feb 24, 2026

I mean this is definitely good, even if it likely isn't a full fix (like discussed above) - the code change LGTM.

It's just the commit message seems misleading: "Map ENOBUFS to WriteError::NothingWritten so the caller retries the frame instead of treating it as a fatal error." - the caller doesn't retry on WriteError::NothingWritten, it relies on a writable kqueue notification (which the commit message implies doesn't arrive) or a kick from the guest.

@nirs
Copy link
Contributor Author

nirs commented Feb 24, 2026

I mean this is definitely good, even if it likely isn't a full fix (like discussed above) - the code change LGTM.

It's just the commit message seems misleading: "Map ENOBUFS to WriteError::NothingWritten so the caller retries the frame instead of treating it as a fatal error." - the caller doesn't retry on WriteError::NothingWritten, it relies on a writable kqueue notification (which the commit message implies doesn't arrive) or a kick from the guest.

Right, "caller retries" is not a good description. The write is retried when the socket is considered writable (need to test if this happen) or the guest kicks us.

I'll try to experiment more and have a more correct description how this is handled.

@mtjhrc
Copy link
Collaborator

mtjhrc commented Feb 24, 2026

I feel like we should be getting the EV_WRITE events. I made a simple test and it seemed to work:
https://gist.github.com/mtjhrc/2a8583cfc82cf913a8402114dda1bb9a

@nirs nirs changed the title virtio/net/unixgram: handle ENOBUFS on macOS by retrying virtio/net/unixgram: Retry and log ENOBUFS Feb 24, 2026
@nirs
Copy link
Contributor Author

nirs commented Feb 24, 2026

I feel like we should be getting the EV_WRITE events. I made a simple test and it seemed to work: https://gist.github.com/mtjhrc/2a8583cfc82cf913a8402114dda1bb9a

Interesting, but there are no timestamps so it is not clear if we got the event immediately after the read.

@nirs
Copy link
Contributor Author

nirs commented Feb 24, 2026

@mtjhrc I'm trying the EV_WRITE way, it seems like a simple change.

@nirs
Copy link
Contributor Author

nirs commented Feb 25, 2026

@mtjhrc Current version should be a complete fix. Tested with vment-helper and podman/gvproxy. I will post updated results later.

@nirs nirs changed the title virtio/net/unixgram: Retry and log ENOBUFS virtio/net/unixgram: Retry on ENOBUFS Feb 25, 2026
@mtjhrc
Copy link
Collaborator

mtjhrc commented Feb 26, 2026

Oh, so we were already busy looping on WriteError::NothingWritten from send - that was an unintended bug.
So to clarify, the EV_WRITE notifications work fine according to your findings (we get the notification)?

I'll try testing this a bit too, but fix looks good (I guess this now touches unixstream / passt too - fixes the busy loop)

@nirs
Copy link
Contributor Author

nirs commented Feb 26, 2026

Oh, so we were already busy looping on WriteError::NothingWritten from send - that was an unintended bug. So to clarify, the EV_WRITE notifications work fine according to your findings (we get the notification)?

@mtjhrc Yes and no. We get WRITE event, but the next write may fail again with ENOBUFS. I added a log to track this.

I'll try testing this a bit too, but fix looks good (I guess this now touches unixstream / passt too - fixes the busy loop)

Yes, the worker change fixes the same issue for unixtream. I did not test with unixstream .

@nirs nirs mentioned this pull request Feb 26, 2026
@nirs
Copy link
Contributor Author

nirs commented Feb 26, 2026

Example debug log showing ENUBUFS recovery

Logs created with #564.

[2026-02-26T18:25:00.438142Z DEBUG utils::macos::epoll] kevent: WRITE fd=3 data=66560
[2026-02-26T18:25:00.438144Z DEBUG utils::macos::epoll] kevent: READ fd=81 data=8
[2026-02-26T18:25:00.438146Z DEBUG utils::macos::epoll] kevent: READ fd=3 data=2490900
[2026-02-26T18:25:00.438143Z DEBUG hvf] EC_DATAABORT 2475884550 1 0 0 2 4 19 0
[2026-02-26T18:25:00.438187Z DEBUG vmm::macos::vstate] vCPU 0 MMIO read 0xa00a060
[2026-02-26T18:25:00.438151Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.438219Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.438222Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.438226Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.438229Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.438232Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.438236Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.438239Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.438241Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.438244Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.438247Z DEBUG devices::virtio::mmio[net]] interrupt: signal_used_queue
[2026-02-26T18:25:00.438261Z DEBUG utils::macos::epoll] EpollEvent new: 0
[2026-02-26T18:25:00.438265Z DEBUG utils::macos::epoll] kevs len: 32
[2026-02-26T18:25:00.438273Z DEBUG utils::macos::epoll] ret: 1
[2026-02-26T18:25:00.438275Z DEBUG utils::macos::epoll] kevent: READ fd=83 data=32
[2026-02-26T18:25:00.438279Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.438282Z DEBUG utils::macos::epoll] EpollEvent new: 0
[2026-02-26T18:25:00.438284Z DEBUG utils::macos::epoll] kevs len: 32
[2026-02-26T18:25:00.438287Z DEBUG utils::macos::epoll] ret: 1
[2026-02-26T18:25:00.438289Z DEBUG utils::macos::epoll] kevent: READ fd=83 data=24
[2026-02-26T18:25:00.438292Z DEBUG utils::macos::epoll] EpollEvent new: 0
[2026-02-26T18:25:00.438309Z DEBUG utils::macos::epoll] kevs len: 32
[2026-02-26T18:25:00.438312Z DEBUG utils::macos::epoll] ret: 1
[2026-02-26T18:25:00.438315Z DEBUG utils::macos::epoll] kevent: READ fd=83 data=16
[2026-02-26T18:25:00.438317Z DEBUG utils::macos::epoll] EpollEvent new: 0
[2026-02-26T18:25:00.438320Z DEBUG utils::macos::epoll] kevs len: 32
[2026-02-26T18:25:00.438322Z DEBUG utils::macos::epoll] ret: 1
[2026-02-26T18:25:00.438324Z DEBUG utils::macos::epoll] kevent: READ fd=83 data=8
[2026-02-26T18:25:00.438327Z DEBUG utils::macos::epoll] EpollEvent new: 0
[2026-02-26T18:25:00.438329Z DEBUG utils::macos::epoll] kevs len: 32
[2026-02-26T18:25:00.438205Z DEBUG hvf] EC_DATAABORT 2475884614 1 1 0 2 4 19 0
[2026-02-26T18:25:00.438347Z DEBUG hvf] EC_DATAABORT 2475884550 1 0 0 2 4 19 0
[2026-02-26T18:25:00.438352Z DEBUG vmm::macos::vstate] vCPU 0 MMIO read 0xa00a060
[2026-02-26T18:25:00.438357Z DEBUG hvf] EC_DATAABORT 2475884614 1 1 0 2 4 19 0
[2026-02-26T18:25:00.438684Z DEBUG hvf] EC_DATAABORT 2474704966 1 1 0 2 4 1 0
[2026-02-26T18:25:00.438260Z DEBUG hvf] EC_DATAABORT 2474704966 1 1 0 2 4 1 0
[2026-02-26T18:25:00.438986Z DEBUG hvf] EC_DATAABORT 2474704966 1 1 0 2 4 1 0
[2026-02-26T18:25:00.439073Z DEBUG utils::macos::epoll] ret: 2
[2026-02-26T18:25:00.439081Z DEBUG utils::macos::epoll] kevent: READ fd=81 data=8
[2026-02-26T18:25:00.439084Z DEBUG utils::macos::epoll] kevent: READ fd=83 data=16
[2026-02-26T18:25:00.439099Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439113Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439127Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439140Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439150Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439161Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439172Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439182Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439435Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439448Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439458Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439469Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439480Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439491Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439520Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439532Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439544Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439555Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439566Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439576Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439588Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439599Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439611Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439623Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439635Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439647Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439663Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439674Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439686Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439699Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439710Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439720Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439732Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439743Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439755Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439766Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439791Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439803Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.439812Z DEBUG devices::virtio::mmio[net]] interrupt: signal_used_queue
[2026-02-26T18:25:00.439819Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.439823Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.439826Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.439829Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.439832Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.439836Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.439839Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.439842Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.439845Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.439848Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.439851Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.439854Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.439867Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.439881Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.439894Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.439907Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.439921Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.439934Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.439946Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.439973Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.439986Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.439999Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440013Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440026Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440039Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440052Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440065Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440078Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440091Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440105Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440117Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440130Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440144Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440160Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440175Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440191Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440206Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440198Z DEBUG hvf] EC_DATAABORT 2475884550 1 0 0 2 4 19 0
[2026-02-26T18:25:00.440294Z DEBUG vmm::macos::vstate] vCPU 0 MMIO read 0xa00a060
[2026-02-26T18:25:00.440330Z DEBUG hvf] EC_DATAABORT 2475884614 1 1 0 2 4 19 0
[2026-02-26T18:25:00.440219Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440568Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440583Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440597Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440610Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440698Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440714Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440728Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440742Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440756Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440769Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440782Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440795Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440808Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440822Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440835Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440848Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440862Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440874Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440887Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440916Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440933Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440947Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440959Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440972Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440984Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.440997Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441010Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441013Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.441076Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441090Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441103Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441117Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441130Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441170Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441184Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441211Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441224Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441237Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441251Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441263Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441277Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441290Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441303Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441315Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441328Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441338Z DEBUG devices::virtio::net::unixgram] Written frame size=45938, written=45938
[2026-02-26T18:25:00.441350Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441363Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441378Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441410Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441489Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441503Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441562Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441582Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441596Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441611Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441625Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441638Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.441642Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.441655Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442073Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442078Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.442082Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.442085Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.442088Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.442092Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.442095Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.442099Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.442102Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.442106Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.442109Z DEBUG devices::virtio::net::unixgram] Written frame size=66, written=66
[2026-02-26T18:25:00.442122Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442134Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442147Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442160Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442173Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442186Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442199Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442211Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442224Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442237Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442249Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442271Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442284Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442297Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442310Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442322Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442334Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442347Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442359Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442375Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442401Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442414Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442427Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442442Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442455Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442468Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442480Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442493Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442506Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442519Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442531Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442543Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442556Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442582Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442595Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442608Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442620Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442632Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442645Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442657Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442669Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442682Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442694Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442707Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442720Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442733Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442745Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442758Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442772Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442786Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442802Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442827Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442839Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442852Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442865Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442877Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442889Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442903Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442916Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442928Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442939Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442951Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442964Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226
[2026-02-26T18:25:00.442977Z INFO  devices::virtio::net::unixgram] write_frame: ENOBUFS
[2026-02-26T18:25:00.442980Z DEBUG utils::macos::epoll] EpollEvent new: 0
[2026-02-26T18:25:00.442983Z DEBUG utils::macos::epoll] kevs len: 32
[2026-02-26T18:25:00.442988Z DEBUG utils::macos::epoll] ret: 3
[2026-02-26T18:25:00.442990Z DEBUG utils::macos::epoll] kevent: READ fd=83 data=8
[2026-02-26T18:25:00.442993Z DEBUG utils::macos::epoll] kevent: WRITE fd=3 data=17996
[2026-02-26T18:25:00.443010Z DEBUG utils::macos::epoll] kevent: READ fd=3 data=4129650
[2026-02-26T18:25:00.443049Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443064Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443078Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443092Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443105Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443119Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443133Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443147Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443161Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443175Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443188Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443202Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443215Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443228Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443241Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443254Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443268Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443280Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443292Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443304Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443317Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443329Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443343Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443356Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443368Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443380Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443409Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443423Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443437Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443450Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443464Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443478Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443492Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443506Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443520Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443533Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443547Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443562Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443576Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443592Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443609Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443742Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443758Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443914Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443930Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443945Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443959Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443973Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.443987Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.444001Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.444015Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.444027Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.444040Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.444054Z DEBUG devices::virtio::net::unixgram] Read eth frame from proxy: 65550 bytes
[2026-02-26T18:25:00.444061Z DEBUG devices::virtio::mmio[net]] interrupt: signal_used_queue
[2026-02-26T18:25:00.444068Z DEBUG utils::macos::epoll] EpollEvent new: 0
[2026-02-26T18:25:00.444071Z DEBUG utils::macos::epoll] kevs len: 32
[2026-02-26T18:25:00.444074Z DEBUG utils::macos::epoll] ret: 1
[2026-02-26T18:25:00.444076Z DEBUG utils::macos::epoll] kevent: READ fd=3 data=3408600
[2026-02-26T18:25:00.444125Z DEBUG utils::macos::epoll] EpollEvent new: 0
[2026-02-26T18:25:00.444129Z DEBUG utils::macos::epoll] kevs len: 32
[2026-02-26T18:25:00.444132Z DEBUG utils::macos::epoll] ret: 1
[2026-02-26T18:25:00.444134Z DEBUG utils::macos::epoll] kevent: WRITE fd=3 data=17996
[2026-02-26T18:25:00.444151Z DEBUG utils::macos::epoll] EpollEvent new: 0
[2026-02-26T18:25:00.444154Z DEBUG utils::macos::epoll] kevs len: 32
[2026-02-26T18:25:00.444333Z DEBUG hvf] EC_DATAABORT 2475884550 1 0 0 2 4 19 0
[2026-02-26T18:25:00.444429Z DEBUG vmm::macos::vstate] vCPU 0 MMIO read 0xa00a060
[2026-02-26T18:25:00.444466Z DEBUG hvf] EC_DATAABORT 2475884614 1 1 0 2 4 19 0
[2026-02-26T18:25:00.444907Z DEBUG utils::macos::epoll] ret: 1
[2026-02-26T18:25:00.444934Z DEBUG utils::macos::epoll] kevent: READ fd=3 data=4129650
[2026-02-26T18:25:00.444942Z DEBUG utils::macos::epoll] EpollEvent new: 0
[2026-02-26T18:25:00.444946Z DEBUG utils::macos::epoll] kevs len: 32
[2026-02-26T18:25:00.446161Z DEBUG utils::macos::epoll] ret: 1
[2026-02-26T18:25:00.446167Z DEBUG utils::macos::epoll] kevent: WRITE fd=3 data=66560
[2026-02-26T18:25:00.446182Z INFO  devices::virtio::net::unixgram] write_frame: ENOBUFS resolved after 4 retries
[2026-02-26T18:25:00.446185Z DEBUG devices::virtio::net::unixgram] Written frame size=65226, written=65226

Timeline

Time Event
2026-02-26T18:25:00.438142Z kevent: WRITE fd=3 data=66560
2026-02-26T18:25:00.442977Z write_frame: ENOBUFS
2026-02-26T18:25:00.442990Z kevent: READ fd=83 data=8
2026-02-26T18:25:00.442993Z kevent: WRITE fd=3 data=17996
2026-02-26T18:25:00.444134Z kevent: WRITE fd=3 data=17996
2026-02-26T18:25:00.446167Z kevent: WRITE fd=3 data=66560
2026-02-26T18:25:00.446182Z write_frame: ENOBUFS resolved after 4 retries
2026-02-26T18:25:00.446185Z Written frame size=65226, written=65226

Based on the timeline, we woke up 4 times on WRITE event. The first 3 write_frame attempts failed with ENOBUFS (we log only the first attempt). The 4th attempt suceeded, so we expect to see "resolved after 3 retries", but we see "resolved after 4 retries". So we woke up another time, probably due to guest notification (kevent: READ fd=83 data=8).

We woke up twice when available socket buffer was 17996, but we try to write 66560 frame. This can explain why we get a write event but we cannot complete the write.

So WRITE event works, but cannot guarantee that the write will be completed.

@nirs nirs force-pushed the retry-on-enobufs branch 2 times, most recently from c6006f4 to 44907ff Compare February 27, 2026 17:14
@nirs nirs marked this pull request as draft March 6, 2026 14:45
@nirs
Copy link
Contributor Author

nirs commented Mar 6, 2026

After testing this change with real ramen testing workload I see issues when podman networking is broken containers/gvisor-tap-vsock#617.
It seems that the change to return the event loop on NothingWritten is related and need more work.

@nirs nirs force-pushed the retry-on-enobufs branch from 607c356 to d172bda Compare March 7, 2026 14:41
@nirs nirs marked this pull request as ready for review March 7, 2026 14:48
@nirs nirs force-pushed the retry-on-enobufs branch 2 times, most recently from 82d5f9b to a3e6b71 Compare March 7, 2026 15:02
@nirs
Copy link
Contributor Author

nirs commented Mar 7, 2026

@mtjhrc Please review again. Current version adds a timer-based retry delay, fixing random hangs when we don't get a WRITE event after ENOBUFS.

@mtjhrc
Copy link
Collaborator

mtjhrc commented Mar 9, 2026

Ugh... sure a timer could resolve the deadlock, but it doesn't seem great.

Thinking about this more I think the problem is that EVFILT_WRITE fires when there is any space in the socket, but the space is not sufficient for our frame, causing us to get ENOBUFS, however since we are using EV_CLEAR we might not get woken up for EV_WRITE again until we progress and use the empty space. This could explain the rarity of the deadlock (there has to be space in the socket, but not enough).

If I am right, using setsockopt SO_SNDLOWAT on the socket in libkrun with the size of the frame we are trying to send, should resolve the issue without having to resort to a timer. (or you can use kqueue's NOTE_LOWAT I think). Could you please try that instead?

@nirs
Copy link
Contributor Author

nirs commented Mar 9, 2026

Ugh... sure a timer could resolve the deadlock, but it doesn't seem great.

Thinking about this more I think the problem is that EVFILT_WRITE fires when there is any space in the socket, but the space is not sufficient for our frame, causing us to get ENOBUFS, however since we are using EV_CLEAR we might not get woken up for EV_WRITE again until we progress and use the empty space. This could explain the rarity of the deadlock (there has to be space in the socket, but not enough).

If I am right, using setsockopt SO_SNDLOWAT on the socket in libkrun with the size of the frame we are trying to send, should resolve the issue without having to resort to a timer. (or you can use kqueue's NOTE_LOWAT I think). Could you please try that instead?

The frame size can change. Do you suggest to use the largest possible frame (65550) once when starting the worker? Or maybe 2 frames to ensure we have space for one fi there is additional space needed?

@mtjhrc
Copy link
Collaborator

mtjhrc commented Mar 9, 2026

Ugh... sure a timer could resolve the deadlock, but it doesn't seem great.
Thinking about this more I think the problem is that EVFILT_WRITE fires when there is any space in the socket, but the space is not sufficient for our frame, causing us to get ENOBUFS, however since we are using EV_CLEAR we might not get woken up for EV_WRITE again until we progress and use the empty space. This could explain the rarity of the deadlock (there has to be space in the socket, but not enough).
If I am right, using setsockopt SO_SNDLOWAT on the socket in libkrun with the size of the frame we are trying to send, should resolve the issue without having to resort to a timer. (or you can use kqueue's NOTE_LOWAT I think). Could you please try that instead?

The frame size can change. Do you suggest to use the largest possible frame (65550) once when starting the worker? Or maybe 2 frames to ensure we have space for one fi there is additional space needed?

I mean we could use the 65550 always, that could work no? (but possibly a bit wasteful)
But also I think we should be able to update it to the actual frame size. I am not sure if kqueue would automatically pick up the socket option change how we want, but surely it would pickup if we reregistered with NOTE_LOWAT for the current frame length (I would think).

@nirs
Copy link
Contributor Author

nirs commented Mar 9, 2026

@mtjhrc I tried both:

Both do not work: under load (iperf3 -P 8 --bidir -t 600) we fail after some time when we get ENOBUFS and we never get WRITE event.

I cannot explain why it does not work, but it many be related to the fact that with datagram sockets on macOS, the send buffer is not used (it only set the maximum frame size #574). The frames are copied to the peer receive buffer.

There is a note that the write check is racy, but I don't see how this an effect our case (2 peers):
https://github.com/apple-oss-distributions/xnu/blob/f6217f891ac0bb64f3d375211650a4c1ff8ca1ea/bsd/kern/uipc_socket.c#L6755

In summary:

  1. We don't know why WRITE | EV_CLEAR can can lead to a hang after ENOBUFS
  2. But it does, easy to reproduce with gvproxy
  3. Using a timer works well (94% of retries complete on the first try)

@nirs nirs force-pushed the retry-on-enobufs branch 3 times, most recently from 27fbde1 to ac485f1 Compare March 10, 2026 06:48
@nirs nirs marked this pull request as draft March 12, 2026 12:23
@nirs
Copy link
Contributor Author

nirs commented Mar 12, 2026

Need a rebase after #567 was merged, will simplify the code.

nirs added 6 commits March 12, 2026 16:32
If write_frame() returns NothingWritten, propagate the error to
process_tx_loop() and return to the event loop. The event loop will wake
us when the socket available space is changed.

Previously when the backend could not write anything we enabled
notifications and retried process_tx(), creating a busy loop ending when
the write complete.

Signed-off-by: Nir Soffer <nirsof@gmail.com>
Add add_oneshot_timer() to register a one-shot EVFILT_TIMER with
microsecond precision. The caller provides a udata value to identify
the timer event, since epoll has no timer concept — timer events are
reported with empty event bits and the caller matches on udata.

This will be used to implement delayed TX retries after ENOBUFS,
where stress testing showed that edge-triggered EVFILT_WRITE does
not re-fire reliably after the error.

Assisted-by: Cursor/Claude Opus 4.6
Signed-off-by: Nir Soffer <nirsof@gmail.com>
When process_tx() fails with NothingWritten, set tx_has_deferred_frame
and schedule a retry using the epoll shim's one-shot timer. The retry
delay is provided by the backend via write_retry_delay_us(), which
defaults to 0 (no timer). Backends opt in by overriding it.

Assisted-by: Cursor/Claude Opus 4.6
Signed-off-by: Nir Soffer <nirsof@gmail.com>
When running iperf3 with gvproxy or vmnet-helper, krunkit breaks
randomly with:

    [2026-02-19T02:53:41Z ERROR devices::virtio::net::worker] Failed to process rx:
    Backend(Internal(ENOBUFS)) (triggered by backend socket readable)

macOS returns ENOBUFS when the kernel socket buffer is full, rather
than blocking or returning EAGAIN on non-blocking sockets. In
vmnet-helper this is handled by retrying the write after 50 microseconds
sleep.

We use non-blocking I/O, and we get WRITE events when the socket becomes
writeable, but because we need to write a complete frame, the write can
fail with ENOBUFS again after we get a WRITE event. Testing shows that
we typically get several WRITE event and ENOBUFS error is resolved after
few retries.

Stress testing shows that sometimes we don't get a WRITE event after the
network proxy read all data from the socket. The network proxy is
blocked on read(), libkrun blocked on kevent() never getting any event,
and the guest is blocked waiting for interrupt. The only reliable way to
recover from this is to retry the write after a delay.

Map ENOBUFS to WriteError::NothingWritten so the write is retried
instead of treating it as a fatal error. We also log a debug log to
make it easy to understand the events.

Override write_retry_delay_us() to return 50 microseconds delay. The
worker use this to retry the write, ensuring that we make progress when
WRITE event does not fire.

Assisted-by: Cursor/Claude Opus 4.6
Signed-off-by: Nir Soffer <nirsof@gmail.com>
ENOBUFS on macOS does not always resolve on the first writable event
from kevent. The writable event fires when any buffer space is
available, but for datagram sockets the entire message must fit
atomically. When writing large frames (e.g. 65226 bytes), the socket
may report writable with insufficient space (e.g. data=17996), causing
send() to return ENOBUFS until enough buffer drains.

Add a retry counter to log the first ENOBUFS event and the number of
retries on recovery:

    [2026-02-26T16:36:24.440890Z INFO  devices::virtio::net::unixgram] write_frame: ENOBUFS
    [2026-02-26T16:36:24.441544Z INFO  devices::virtio::net::unixgram] write_frame: ENOBUFS resolved after 1 retries

We use info level since ENOBUFS events are rare and testing in debug
level is about 3x slower, distorting the results.

ENOBUFS event are rare when testing with vment-helper, and common when
testing with gvproxy. The following stats are from 10 minutes stress
test using `iperf3 -c vm-address -P 8 --bidir -t 600`.

vment-helper stats:

    Total ENOBUFS events: 293

    Retries   Count       %       Min       Avg       P99       Max
          1     280   95.6%       17us      425us     1274us     1470us
          2      12    4.1%      517us      656us     1047us     1047us
          3       1    0.3%      624us      624us      624us      624us

    Overall: min=17us avg=436us p50=532us p99=1274us max=1470us

    Retry count histogram:
        1 retries: ################################################## 280
        2 retries: ## 12
        3 retries: # 1

gvproxy stats:

    Total ENOBUFS events: 18346

    Retries   Count       %       Min       Avg       P99       Max
          1   17291   94.2%        7us       85us      394us     1566us
          2     884    4.8%       14us      188us      650us      923us
          3     151    0.8%       29us      271us     1095us     2092us
          4      16    0.1%       80us      319us      959us      959us
          5       4    0.0%       42us      280us      691us      691us

    Overall: min=7us avg=92us p50=66us p99=452us max=2092us

    Retry count histogram:
        1 retries: ################################################## 17291
        2 retries: ## 884
        3 retries: # 151
        4 retries: # 16
        5 retries: # 4

Assisted-by: Cursor/Claude Opus 4.6
Signed-off-by: Nir Soffer <nirsof@gmail.com>
In read_frame we log:

    Read eth frame from proxy: 65550 bytes

But in write_frame we log:

    Written frame size=65226, written=65226

The frame size is always equal to the return value. There is no partial
write with datagram socket. Unify the log to:

    Written eth frame to proxy: 65226 bytes

Signed-off-by: Nir Soffer <nirsof@gmail.com>
@nirs nirs force-pushed the retry-on-enobufs branch from ac485f1 to 990ca30 Compare March 12, 2026 17:02
@nirs nirs marked this pull request as ready for review March 12, 2026 17:03
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Network breaks under high load randomly with: ERROR devices::virtio::net::worker] Failed to process rx: Backend(Internal(ENOBUFS))

3 participants